当Dubbo遇上Arthas：排查问题的实践

Apache Dubbo是Alibaba开源的高性能RPC框架，在国内有非常多的用户。

• Github: https://github.com/apache/incubator-dubbo

• 文档：http://dubbo.incubator.apache.org/zh-cn/

Arthas是Alibaba开源的应用诊断利器，9月份开源以来，Github Star数三个月超过6000。

• Github: https://github.com/alibaba/arthas

• 文档：https://alibaba.github.io/arthas/

• Arthas开源交流QQ群: 916328269

• Arthas开源交流钉钉群: 21965291

当Dubbo遇上Arthas，会碰撞出什么样的火花呢？下面来分享Arthas排查Dubbo问题的一些经验。

dubbo-arthas-demo

下面的排查分享基于这个 dubbo-arthas-demo，非常简单的一个应用，浏览器请求从Spring MVC到Dubbo Client，再发送到Dubbo Server。

Demo里有两个spring boot应用，可以先启动 server-demo，再启动 client-demo。

• https://github.com/hengyunabc/dubbo-arthas-demo

1.  /user/{id}    ->   UserService    ->   UserServiceImpl

2.   Browser           Dubbo Client          Dubbo Server

Client端：

1. @RestController

2. public class UserController {

3.    @Reference(version = "1.0.0")

4.    private UserService userService;

5.    @GetMapping("/user/{id}")

6.    public User findUserById(@PathVariable Integer id) {

7.        return userService.findUser(id);

8.    }

Server端：

1. @Service(version = "1.0.0")

2. public class UserServiceImpl implements UserService {

3.    @Override

4.    public User findUser(int id) {

5.        if (id < 1) {

6.            throw new IllegalArgumentException("user id < 1, id: " + id);

7.        }

8.        for (User user : users) {

9.            if (user.getId() == id) {

10.                return user;

11.            }

12.        }

13.        throw new RuntimeException("Can not find user, id: " + id);

14.    }

Arthas快速开始

• https://alibaba.github.io/arthas/install-detail.html

1. $ wget https://alibaba.github.io/arthas/arthas-boot.jar

2. $ java -jar arthas-boot.jar

启动后，会列出所有的java进程，选择1，然后回车，就会连接上 ServerDemoApplication

1. $ java -jar arthas-boot.jar

2. * [1]: 43523 ServerDemoApplication

3.  [2]: 22342

4.  [3]: 44108 ClientDemoApplication

5. 1

6. [INFO] arthas home: /Users/hengyunabc/.arthas/lib/3.0.5/arthas

7. [INFO] Try to attach process 43523

8. [INFO] Attach process 43523 success.

9. [INFO] arthas-client connect 127.0.0.1 3658

10.  ,---.  ,------. ,--------.,--.  ,--.  ,---.   ,---.

11. /  O  \ |  .--. ''--.  .--'|  '--'  | /  O  \ '   .-'

12. |  .-.  ||  '--'.'   |  |   |  .--.  ||  .-.  |`.  `-.

13. |  | |  ||  |\  \    |  |   |  |  |  ||  | |  |.-'    |

14. `--' `--'`--' '--'   `--'   `--'  `--'`--' `--'`-----'

15. wiki: https://alibaba.github.io/arthas

16. version: 3.0.5

17. pid: 43523

18. time: 2018-12-05 16:23:52

19. $

Dubbo线上服务抛出异常，怎么获取调用参数？

• https://alibaba.github.io/arthas/watch.html

当线上服务抛出异常时，最着急的是什么参数导致了抛异常？

在demo里，访问 http://localhost:8080/user/0 ， UserServiceImpl就会抛出一个异常，因为user id不合法。

在Arthas里执行 watch com.example.UserService*-e-x2'{params,throwExp}' ，然后再次访问，就可以看到watch命令把参数和异常都打印出来了。

1. $ watch com.example.UserService * -e -x 2 '{params,throwExp}'

2. Press Ctrl+C to abort.

3. Affect(class-cnt:1 , method-cnt:4) cost in 230 ms.

4. ts=2018-12-05 16:26:44; [cost=3.905523ms] result=@ArrayList[

5.    @Object[][

6.        @Integer[0],

7.    ],

8.    java.lang.IllegalArgumentException: user id < 1, id: 0

9.    at com.example.UserServiceImpl.findUser(UserServiceImpl.java:24)

10.    at com.alibaba.dubbo.common.bytecode.Wrapper1.invokeMethod(Wrapper1.java)

11.    at com.alibaba.dubbo.rpc.proxy.javassist.JavassistProxyFactory$1.doInvoke(JavassistProxyFactory.java:45)

12.    at com.alibaba.dubbo.rpc.proxy.AbstractProxyInvoker.invoke(AbstractProxyInvoker.java:71)

13.    at com.alibaba.dubbo.config.invoker.DelegateProviderMetaDataInvoker.invoke(DelegateProviderMetaDataInvoker.java:48)

14.    at com.alibaba.dubbo.rpc.protocol.InvokerWrapper.invoke(InvokerWrapper.java:52)

15.    at com.alibaba.dubbo.rpc.filter.ExceptionFilter.invoke(ExceptionFilter.java:61)

怎样线上调试Dubbo服务代码?

• https://alibaba.github.io/arthas/redefine.html

在本地开发时，可能会用到热部署工具，直接改代码，不需要重启应用。但是在线上环境，有没有办法直接动态调试代码？比如增加日志。

在Arthas里，可以通过 redefine命令来达到线上不重启，动态更新代码的效果。

比如我们修改下 UserServiceImpl，用 System.out打印出具体的 User对象来：

1.    public User findUser(int id) {

2.        if (id < 1) {

3.            throw new IllegalArgumentException("user id < 1, id: " + id);

4.        }

5.        for (User user : users) {

6.            if (user.getId() == id) {

7.                System.out.println(user);

8.                return user;

9.            }

10.        }

11.        throw new RuntimeException("Can not find user, id: " + id);

12.    }

本地编绎后，把 server-demo/target/classes/com/example/UserServiceImpl.class传到线上服务器，然后用 redefine命令来更新代码：

1. $ redefine -p /tmp/UserServiceImpl.class

2. redefine success, size: 1

这样子更新成功之后，访问 http://localhost:8080/user/1 ，在 ServerDemoApplication的控制台里就可以看到打印出了user信息。

怎样动态修改Dubbo的logger级别?

• https://alibaba.github.io/arthas/ognl.html

• https://alibaba.github.io/arthas/sc.html

• https://commons.apache.org/proper/commons-ognl/language-guide.html

在排查问题时，需要查看到更多的信息，如果可以把logger级别修改为 DEBUG，就非常有帮助。

ognl是apache开源的一个轻量级表达式引擎。下面通过Arthas里的 ognl命令来动态修改logger级别。

首先获取Dubbo里 TraceFilter的一个logger对象，看下它的实现类，可以发现是log4j。

1. $ ognl '@[e-mail]'

2. @Log4jLogger[

3.    FQCN=@String[com.alibaba.dubbo.common.logger.support.FailsafeLogger],

4.    logger=@Logger[org.apache.log4j.Logger@2f19bdcf],

5. ]

再用 sc命令来查看具体从哪个jar包里加载的：

1. $ sc -d org.apache.log4j.Logger

2. class-info        org.apache.log4j.Logger

3. code-source       /Users/hengyunabc/.m2/repository/org/slf4j/log4j-over-slf4j/1.7.25/log4j-over-slf4j-1.7.25.jar

4. name              org.apache.log4j.Logger

5. isInterface       false

6. isAnnotation      false

7. isEnum            false

8. isAnonymousClass  false

9. isArray           false

10. isLocalClass      false

11. isMemberClass     false

12. isPrimitive       false

13. isSynthetic       false

14. simple-name       Logger

15. modifier          public

16. annotation

17. interfaces

18. super-class       +-org.apache.log4j.Category

19.                     +-java.lang.Object

20. class-loader      +-sun.misc.Launcher$AppClassLoader@5c647e05

21.                     +-sun.misc.Launcher$ExtClassLoader@59878d35

22. classLoaderHash   5c647e05

23. Affect(row-cnt:1) cost in 126 ms.

可以看到log4j是通过slf4j代理的。

那么通过 org.slf4j.LoggerFactory获取 root logger，再修改它的level：

1. $ ognl '@org.slf4j.LoggerFactory@getLogger("root").setLevel(@ch.qos.logback.classic.Level@DEBUG)'

2. null

3. $ ognl '@org.slf4j.LoggerFactory@getLogger("root").getLevel().toString()'

4. @String[DEBUG]

可以看到修改之后， root logger的level变为 DEBUG。

怎样减少测试小姐姐重复发请求的麻烦?

• https://alibaba.github.io/arthas/tt.html

在平时开发时，可能需要测试小姐姐发请求过来联调，但是我们在debug时，可能不小心直接跳过去了。这样子就尴尬了，需要测试小姐姐再发请求过来。

Arthas里提供了 tt命令，可以减少这种麻烦，可以直接重放请求。

1. $ tt -t com.example.UserServiceImpl findUser

2. Press Ctrl+C to abort.

3. Affect(class-cnt:1 , method-cnt:1) cost in 145 ms.

4. INDEX      TIMESTAMP              COST(ms)      IS-RET     IS-EXP    OBJECT       CLASS              METHOD

5. ----------------------------------------------------------------------------------------------------------------

6. 1000       2018-12-05 17:47:52    1.56523       true       false     0x3233483    UserServiceImpl    findUser

7. 1001       2018-12-05 17:48:03    0.286176      false      true      0x3233483    UserServiceImpl    findUser

8. 1002       2018-12-05 17:48:11    90.324335     true       false     0x3233483    UserServiceImpl    findUser

上面的 tt-t命令捕获到了3个请求。然后通过 tt--play可以重放请求：

1. $ tt --play -i 1000

2. RE-INDEX       1000

3. GMT-REPLAY     2018-12-05 17:55:50

4. OBJECT         0x3233483

5. CLASS          com.example.UserServiceImpl

6. METHOD         findUser

7. PARAMETERS[0]  @Integer[1]

8. IS-RETURN      true

9. IS-EXCEPTION   false

10. RETURN-OBJ     @User[

11.                    id=@Integer[1],

12.                    name=@String[Deanna Borer],

13.                ]

14. Time fragment[1000] successfully replayed.

15. Affect(row-cnt:1) cost in 4 ms.

Dubbo运行时有哪些Filter? 耗时是多少?

• https://alibaba.github.io/arthas/trace.html

Dubbo运行时会加载很多的Filter，那么一个请求会经过哪些Filter处理，Filter里的耗时又是多少呢？

通过Arthas的 trace命令，可以很方便地知道Filter的信息，可以看到详细的调用栈和耗时。

1. $ trace com.alibaba.dubbo.rpc.Filter *

2. Press Ctrl+C to abort.

3. Affect(class-cnt:19 , method-cnt:59) cost in 1441 ms.

4. `---ts=2018-12-05 19:07:26;thread_name=DubboServerHandler-30.5.125.152:20880-thread-10;id=3e;is_daemon=true;priority=5;TCCL=sun.misc.Launcher$AppClassLoader@5c647e05

5.    `---[8.435844ms] com.alibaba.dubbo.rpc.filter.EchoFilter:invoke()

6.        +---[0.124572ms] com.alibaba.dubbo.rpc.Invocation:getMethodName()

7.        +---[0.065123ms] java.lang.String:equals()

8.        `---[7.762928ms] com.alibaba.dubbo.rpc.Invoker:invoke()

9.            `---[7.494124ms] com.alibaba.dubbo.rpc.filter.ClassLoaderFilter:invoke()

10.                +---[min=0.00355ms,max=0.049922ms,total=0.057637ms,count=3] java.lang.Thread:currentThread()

11.                +---[0.0126ms] java.lang.Thread:getContextClassLoader()

12.                +---[0.02188ms] com.alibaba.dubbo.rpc.Invoker:getInterface()

13.                +---[0.004115ms] java.lang.Class:getClassLoader()

14.                +---[min=0.003906ms,max=0.014058ms,total=0.017964ms,count=2] java.lang.Thread:setContextClassLoader()

15.                `---[7.033486ms] com.alibaba.dubbo.rpc.Invoker:invoke()

16.                    `---[6.869488ms] com.alibaba.dubbo.rpc.filter.GenericFilter:invoke()

17.                        +---[0.01481ms] com.alibaba.dubbo.rpc.Invocation:getMethodName()

Dubbo动态代理是怎样实现的?

• https://alibaba.github.io/arthas/jad.html

• com.alibaba.dubbo.common.bytecode.Wrapper

通过Arthas的 jad命令，可以看到Dubbo通过javaassist动态生成的Wrappr类的代码：

1. $ jad com.alibaba.dubbo.common.bytecode.Wrapper1

2. ClassLoader:

3. +-sun.misc.Launcher$AppClassLoader@5c647e05

4.  +-sun.misc.Launcher$ExtClassLoader@59878d35

5. Location:

6. /Users/hengyunabc/.m2/repository/com/alibaba/dubbo/2.5.10/dubbo-2.5.10.jar

7. package com.alibaba.dubbo.common.bytecode;

8. public class Wrapper1

9. extends Wrapper

10. implements ClassGenerator.DC {

11.    public Object invokeMethod(Object object, String string, Class[] arrclass, Object[] arrobject) throws InvocationTargetException {

12.        UserServiceImpl userServiceImpl;

13.        try {

14.            userServiceImpl = (UserServiceImpl)object;

15.        }

16.        catch (Throwable throwable) {

17.            throw new IllegalArgumentException(throwable);

18.        }

19.        try {

20.            if ("findUser".equals(string) && arrclass.length == 1) {

21.                return userServiceImpl.findUser(((Number)arrobject[0]).intValue());

22.            }

23.            if ("listUsers".equals(string) && arrclass.length == 0) {

24.                return userServiceImpl.listUsers();

25.            }

26.            if ("findUserByName".equals(string) && arrclass.length == 1) {

27.                return userServiceImpl.findUserByName((String)arrobject[0]);

28.            }

29.        }

获取Spring context

除了上面介绍的一些排查技巧，下面分享一个获取Spring Context，然后“为所欲为”的例子。

在Dubbo里有一个扩展 com.alibaba.dubbo.config.spring.extension.SpringExtensionFactory，把Spring Context保存到了里面。 因此，我们可以通过 ognl命令获取到。

1. $ ognl '#context=@[e-mail], #context.getBean("userServiceImpl").findUser(1)'

2. @User[

3.    id=@Integer[1],

4.    name=@String[Deanna Borer],

5. ]

解释下上面的语句：

• [e-mail] 获取到 SpringExtensionFactory里保存的spring context对象

• #context.getBean("userServiceImpl").findUser(1) 获取到 userServiceImpl再执行一次调用

只要充分发挥想像力，组合Arthas里的各种命令，可以发挥出神奇的效果。

总结

本篇文章来自杭州Dubbo Meetup的分享《当DUBBO遇上Arthas - 排查问题的实践》，希望对大家线上排查Dubbo问题有帮助。

分享的PDF可以在 https://github.com/alibaba/arthas/issues/327 里下载。